Fix flaky 3PID inhibit error unit tests#19913
Conversation
These tests could flake as the endpoints would intentionally wait for 100-1000ms in order to prevent a timing attack allowing one to deduce whether an email was already registered. The tests only waiting 1000ms for the endpoint to return, so a randomly-chosen jitter any higher than ~900ms would cause the test to fail. I'm unsure why this started failing recently, as the jitter has been in place for years. There was a recent change with the `Duration` work - we used `randrandom.randint(1, 10) / 10` and now `Duration(milliseconds=random.randint(100, 1000))`, but the math is technically equivalent.
| # The endpoint intentionally adds up to 1000ms of jitter to avoid | ||
| # leaking whether the email address is bound to an account. | ||
| timeout_ms=3000, |
There was a problem hiding this comment.
The tests were only waiting 1000ms for the endpoint to return, so a randomly-chosen jitter any higher than ~900ms would cause the test to fail.
I'm not understanding the logic behind 3000ms?
There was a problem hiding this comment.
This should actually be fine with 1000ms (the default).
The only reason it's not is because await_result(...) is a bit flaky. For example, the first advance(0.1) in await_result(...) triggers any scheduled work (like database ThreadPool queries as part of the request), then the 1000ms jitter sleep starts, but await_result(...) can give up after another 0.9s (still 1s total but 0.1s short of the sleep finishing). This edge case happens when the floating point math satisfies self._reactor.seconds() > end_time one iteration early so it waits exactly 1s (10 iterations). The normal case (when everything passes) is because it gets an extra self._reactor.advance(0.1) iteration (11 iterations -> waits 1.1s).
To make it more clear, here is how we could manually drive this to completion reliably:
(test_request_token_existing_email_inhibit_error in tests/rest/client/test_register.py)
channel = self.make_request(
"POST",
b"register/email/requestToken",
{"client_secret": "foobar", "email": email, "send_attempt": 1},
# We're going to drive the reactor ourselves (just below)
await_result=False
)
# Wait for database queries to run so we can get the jitter sleep started
self.reactor.advance(0)
# Wait for any potential jitter (up to 1 second)
self.reactor.advance(Duration(seconds=1).as_secs())Related to #19394 (comment) and #19734 (comment)
I think a better fix would be to update await_result(...) to self._reactor.advance(0) before it starts its loop. This way, we don't burn any reactor advance time on things that are actually scheduled now (get rid of the foot-guns).
I'm working on improving FakeChannel.await_result(...) in #19879 so I'll include the fix there ⏩
Overall, I think this PR should probably be reverted. We could still benefit from the comments pointing out the jitter here though.
There was a problem hiding this comment.
Thanks for diving in deep here! That makes sense, I didn't consider that other work could be delaying the response before the jitter even started.
I noticed that the fix was included in #19879, and the PR has now merged. Nice!
I agree that we no longer need to mess with the timeout in tests if await_result acts as expected, and actually it may be a bad smell to encourage tests to do so (leading to overzealous delays in unit tests). Happy to revert this PR minus the jitter comments.
I'm not understanding the logic behind 3000ms?
It was just an arbitrarily higher value to get substantially far away from 1000ms.
| client_secret: str, | ||
| ip: str = "127.0.0.1", | ||
| next_link: str | None = None, | ||
| timeout_ms: int = 1000, |
There was a problem hiding this comment.
We can use the Duration class
| client_secret: str, | ||
| ip: str = "127.0.0.1", | ||
| next_link: str | None = None, | ||
| timeout_ms: int = 1000, |
There was a problem hiding this comment.
Why 1000 default if that doesn't work in these cases?
There was a problem hiding this comment.
The reasoning was that the jitter was an edge case that only applied to this endpoint, and thus these tests.
There was a problem hiding this comment.
_request_token(...) is a custom method for the tests for this endpoint (not a general method)
| await_result: bool = True, | ||
| custom_headers: Iterable[CustomHeaderType] | None = None, | ||
| client_ip: str = "127.0.0.1", | ||
| timeout_ms: int = 1000, |
There was a problem hiding this comment.
Historically, we instead used this pattern:
channel = self.make_request(
"GET",
f"/_matrix/media/r0/thumbnail/{self.media_id}{params}",
await_result=False,
)
channel.await_result(timeout_ms=1000)The new shortcut doesn't seem bad though.
Based one explanation from #19913 (comment)
Fixes flakes in the following unit tests:
tests.rest.client.test_account.PasswordResetTestCase.test_password_reset_bad_email_inhibit_errortests.rest.client.test_register.RegisterRestServletTestCase.test_request_token_existing_email_inhibit_errorThese tests could flake as the endpoints would intentionally wait for 100-1000ms in order to prevent a timing attack allowing one to deduce whether an email was already registered.
The tests were only waiting 1000ms for the endpoint to return, so a randomly-chosen jitter any higher than ~900ms would cause the test to fail.
I'm unsure why this started failing recently, as the jitter has been in place for years. There was a recent change with the
Durationwork - we usedrandrandom.randint(1, 10) / 10and nowDuration(milliseconds=random.randint(100, 1000)), but the math is technically equivalent.Dev notes
There are multiple places we add jitter in both
synapse/rest/client/account.pyandsynapse/rest/client/register.pysynapse/synapse/rest/client/account.py
Lines 125 to 131 in 963e486
synapse/synapse/rest/client/register.py
Lines 157 to 165 in 963e486
Pull Request Checklist
EventStoretoEventWorkerStore.".code blocks.